AWS CLIを使ってDMSタスクの詳細ログを出力する方法

にしざわ

2016.12.25

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

西澤です。DMSによるデータ転送は非常に便利なのですが、一方ではエラーになった際の原因追跡に苦戦することが多いのか、お客様からのお問合わせもいただくことが多いのが現状です。

この課題を解決する為、今回は先日リリースされたDMSタスクの詳細ログ出力機能を、みんな大好きAWS CLIから設定する方法をご紹介します。

AWS Developer Forums: Enabling detail debug logging for a migration task

DMS詳細ログを設定する流れ

今回は以下の流れでログを作成することにしました。詳細は後でそれぞれ補足していきます。

AWS Management Consoleから仮のDMSタスクを作成する
作成したDMSタスクから必要な情報を抽出する
ReplicationTaskSettingsで詳細ログ出力設定用のJSONを編集する
詳細ログ出力が有効な新しいDMSタスクを作成する

本当はいきなりログ出力が有効なDMSタスクを作成できれば一番良いのですが、それがなかなか難しいので、まずは叩き台となる仮タスクを作成してその情報を元に新しいタスクを作るという方法を取りたいと思います。

DMS詳細ログをAWS CLIで設定する

DMSタスクの詳細ログ機能ですが、残念ながら執筆時点ではAWS Management Consoleから設定することはできないようです。また、既存のタスクの設定を変更するのではなく、タスクを作成する際のオプションとして指定する形になりますのでご注意ください。

AWS Management Consoleから仮のDMSタスクを作成する

CreateReplicationTaskにて指定するReplicationTaskSettingsの項目は情報量がかなり多く、このJSONを1から作成するのはかなり難しいと思います。

Task Settings for AWS Database Migration Service Tasks - AWS Database Migration Service

ですので、まず作成したいDMSタスク作成は、AWS Management Consoleからやっていただくことをお勧めします。Start task on createの項目は、チェックを付けてしまうとタスク作成と同時に開始されてしまうので、このチェックは外しておきましょう。

start_task_on_create

作成したDMSタスクから必要な情報を抽出する

ここから、AWS CLIの出番です。作成したDMSタスクの情報を抽出してみます。

$ DMSTASKNAME=dmstest
$ aws dms describe-replication-tasks \
--query "ReplicationTasks[?ReplicationTaskIdentifier==\`${DMSTASKNAME}\`]"
[
{
"SourceEndpointArn": "arn:aws:dms:us-west-2:123456789012:endpoint:K7XIXXXXXXXXXXXXXXXXXXA4DE",
"ReplicationTaskIdentifier": "dmstest",
"ReplicationInstanceArn": "arn:aws:dms:us-west-2:123456789012:rep:2DKQXXXXXXXXXXXXXXXXXXRUK4",
"TableMappings": "{\n \"rules\": [\n {\n \"rule-type\": \"selection\",\n \"rule-id\": \"0\",\n \"rule-name\": \"selection rule\",\n \"rule-action\": \"include\",\n \"object-locator\": {\n \"schema-name\": \"SCOTT\",\n \"table-name\": \"%\"\n }\n },\n {\n \"rule-type\": \"transformation\",\n \"rule-id\": \"1\",\n \"rule-name\": \"RuleName 1\",\n \"rule-action\": \"convert-lowercase\",\n \"rule-target\": \"schema\",\n \"object-locator\": {\n \"schema-name\": \"%\"\n }\n },\n {\n \"rule-type\": \"transformation\",\n \"rule-id\": \"2\",\n \"rule-name\": \"RuleName 2\",\n \"rule-action\": \"convert-lowercase\",\n \"rule-target\": \"table\",\n \"object-locator\": {\n \"schema-name\": \"%\",\n \"table-name\": \"%\"\n }\n }\n ]\n}",
"ReplicationTaskStats": {
"TablesLoading": 0,
"TablesQueued": 0,
"TablesErrored": 0,
"FullLoadProgressPercent": 0,
"TablesLoaded": 0,
"ElapsedTimeMillis": 0
},
"Status": "ready",
"ReplicationTaskArn": "arn:aws:dms:us-west-2:123456789012:task:3LHXXXXXXXXXXXXXXXXXXXU4DQ",
"ReplicationTaskCreationDate": 1482510411.125,
"MigrationType": "full-load",
"TargetEndpointArn": "arn:aws:dms:us-west-2:123456789012:endpoint:4VO3XXXXXXXXXXXXXXXXXXEHX4",
"ReplicationTaskSettings": "{\"TargetMetadata\":{\"TargetSchema\":\"\",\"SupportLobs\":true,\"FullLobMode\":false,\"LobChunkSize\":0,\"LimitedSizeLobMode\":true,\"LobMaxSize\":32,\"LoadMaxFileSize\":0,\"ParallelLoadThreads\":0,\"BatchApplyEnabled\":false},\"FullLoadSettings\":{\"FullLoadEnabled\":true,\"ApplyChangesEnabled\":false,\"TargetTablePrepMode\":\"DROP_AND_CREATE\",\"CreatePkAfterFullLoad\":false,\"StopTaskCachedChangesApplied\":false,\"StopTaskCachedChangesNotApplied\":false,\"ResumeEnabled\":false,\"ResumeMinTableSize\":100000,\"ResumeOnlyClusteredPKTables\":true,\"MaxFullLoadSubTasks\":8,\"TransactionConsistencyTimeout\":600,\"CommitRate\":10000},\"Logging\":{\"EnableLogging\":true,\"LogComponents\":[{\"Id\":\"SOURCE_UNLOAD\",\"Severity\":\"LOGGER_SEVERITY_DEFAULT\"},{\"Id\":\"SOURCE_CAPTURE\",\"Severity\":\"LOGGER_SEVERITY_DEFAULT\"},{\"Id\":\"TARGET_LOAD\",\"Severity\":\"LOGGER_SEVERITY_DEFAULT\"},{\"Id\":\"TARGET_APPLY\",\"Severity\":\"LOGGER_SEVERITY_DEFAULT\"},{\"Id\":\"TASK_MANAGER\",\"Severity\":\"LOGGER_SEVERITY_DEFAULT\"}],\"CloudWatchLogGroup\":\"dms-tasks-dmsrepl\",\"CloudWatchLogStream\":\"dms-task-3LHELZM7REUYLXLVKALLNZU4DQ\"},\"ControlTablesSettings\":{\"historyTimeslotInMinutes\":5,\"ControlSchema\":\"\",\"HistoryTimeslotInMinutes\":5,\"HistoryTableEnabled\":false,\"SuspendedTablesTableEnabled\":false,\"StatusTableEnabled\":false},\"StreamBufferSettings\":{\"StreamBufferCount\":3,\"StreamBufferSizeInMB\":8,\"CtrlStreamBufferSizeInMB\":5},\"ChangeProcessingDdlHandlingPolicy\":{\"HandleSourceTableDropped\":true,\"HandleSourceTableTruncated\":true,\"HandleSourceTableAltered\":true},\"ErrorBehavior\":{\"DataErrorPolicy\":\"LOG_ERROR\",\"DataTruncationErrorPolicy\":\"LOG_ERROR\",\"DataErrorEscalationPolicy\":\"SUSPEND_TABLE\",\"DataErrorEscalationCount\":0,\"TableErrorPolicy\":\"SUSPEND_TABLE\",\"TableErrorEscalationPolicy\":\"STOP_TASK\",\"TableErrorEscalationCount\":0,\"RecoverableErrorCount\":-1,\"RecoverableErrorInterval\":5,\"RecoverableErrorThrottling\":true,\"RecoverableErrorThrottlingMax\":1800,\"ApplyErrorDeletePolicy\":\"IGNORE_RECORD\",\"ApplyErrorInsertPolicy\":\"LOG_ERROR\",\"ApplyErrorUpdatePolicy\":\"LOG_ERROR\",\"ApplyErrorEscalationPolicy\":\"LOG_ERROR\",\"ApplyErrorEscalationCount\":0,\"FullLoadIgnoreConflicts\":true},\"ChangeProcessingTuning\":{\"BatchApplyPreserveTransaction\":true,\"BatchApplyTimeoutMin\":1,\"BatchApplyTimeoutMax\":30,\"BatchApplyMemoryLimit\":500,\"BatchSplitSize\":0,\"MinTransactionSize\":1000,\"CommitTimeout\":1,\"MemoryLimitTotal\":1024,\"MemoryKeepTime\":60,\"StatementCacheSize\":50}}"
}
]

実際の設定量と比較すると意外ですが、実体はかなりの情報量であることがわかります。この情報から、必要な情報を抽出していきましょう。下記の4つはそのまま取得すれば良いと思います。

$ SourceEndpointArn=$(aws dms describe-replication-tasks \
--query "ReplicationTasks[?ReplicationTaskIdentifier==\`${DMSTASKNAME}\`].SourceEndpointArn" \
--output text)
$ TargetEndpointArn=$(aws dms describe-replication-tasks \
--query "ReplicationTasks[?ReplicationTaskIdentifier==\`${DMSTASKNAME}\`].TargetEndpointArn" \
--output text)
$ ReplicationInstanceArn=$(aws dms describe-replication-tasks \
--query "ReplicationTasks[?ReplicationTaskIdentifier==\`${DMSTASKNAME}\`].ReplicationInstanceArn" \
--output text)
$ MigrationType=$(aws dms describe-replication-tasks \
--query "ReplicationTasks[?ReplicationTaskIdentifier==\`${DMSTASKNAME}\`].MigrationType" \
--output text)

TableMappingsとReplicationTaskSettingsはJSONとして利用できるように、ファイルに出力しておきます。こちらで試したところ、TableMappingsは改行あり、ReplicationTaskSettingsは改行なしのJSONファイルになっていました。

$ aws dms describe-replication-tasks \
--query "ReplicationTasks[?ReplicationTaskIdentifier==\`${DMSTASKNAME}\`].TableMappings" \
--output text > TableMappings.json
$ cat TableMappings.json
{
"rules": [
{
"rule-type": "selection",
"rule-id": "0",
"rule-name": "selection rule",
"rule-action": "include",
"object-locator": {
"schema-name": "SCOTT",
"table-name": "%"
}
},
{
"rule-type": "transformation",
"rule-id": "1",
"rule-name": "RuleName 1",
"rule-action": "convert-lowercase",
"rule-target": "schema",
"object-locator": {
"schema-name": "%"
}
},
{
"rule-type": "transformation",
"rule-id": "2",
"rule-name": "RuleName 2",
"rule-action": "convert-lowercase",
"rule-target": "table",
"object-locator": {
"schema-name": "%",
"table-name": "%"
}
}
]
}

ReplicationTaskSettingsが今回の詳細ログ出力を設定する箇所となります。具体的には、下記のハイライト行にある"Severity": "LOGGER_SEVERITY_DEFAULT"の項目です。

$ aws dms describe-replication-tasks \
    --query "ReplicationTasks[?ReplicationTaskIdentifier==\`${DMSTASKNAME}\`].ReplicationTaskSettings" \
    --output text > ReplicationTaskSettings.json
$ cat ReplicationTaskSettings.json | jq .
{
  "TargetMetadata": {
    "TargetSchema": "",
    "SupportLobs": true,
    "FullLobMode": false,
    "LobChunkSize": 0,
    "LimitedSizeLobMode": true,
    "LobMaxSize": 32,
    "LoadMaxFileSize": 0,
    "ParallelLoadThreads": 0,
    "BatchApplyEnabled": false
  },
  "FullLoadSettings": {
    "FullLoadEnabled": true,
    "ApplyChangesEnabled": false,
    "TargetTablePrepMode": "DROP_AND_CREATE",
    "CreatePkAfterFullLoad": false,
    "StopTaskCachedChangesApplied": false,
    "StopTaskCachedChangesNotApplied": false,
    "ResumeEnabled": false,
    "ResumeMinTableSize": 100000,
    "ResumeOnlyClusteredPKTables": true,
    "MaxFullLoadSubTasks": 8,
    "TransactionConsistencyTimeout": 600,
    "CommitRate": 10000
  },
  "Logging": {
    "EnableLogging": true,
    "LogComponents": [
      {
        "Id": "SOURCE_UNLOAD",
        "Severity": "LOGGER_SEVERITY_DEFAULT"
      },
      {
        "Id": "SOURCE_CAPTURE",
        "Severity": "LOGGER_SEVERITY_DEFAULT"
      },
      {
        "Id": "TARGET_LOAD",
        "Severity": "LOGGER_SEVERITY_DEFAULT"
      },
      {
        "Id": "TARGET_APPLY",
        "Severity": "LOGGER_SEVERITY_DEFAULT"
      },
      {
        "Id": "TASK_MANAGER",
        "Severity": "LOGGER_SEVERITY_DEFAULT"
      }
    ],
    "CloudWatchLogGroup": "dms-tasks-dmsrepl",
    "CloudWatchLogStream": "dms-task-3LHELZM7REUYLXLVKALLNZU4DQ"
  },
  "ControlTablesSettings": {
    "historyTimeslotInMinutes": 5,
    "ControlSchema": "",
    "HistoryTimeslotInMinutes": 5,
    "HistoryTableEnabled": false,
    "SuspendedTablesTableEnabled": false,
    "StatusTableEnabled": false
  },
  "StreamBufferSettings": {
    "StreamBufferCount": 3,
    "StreamBufferSizeInMB": 8,
    "CtrlStreamBufferSizeInMB": 5
  },
  "ChangeProcessingDdlHandlingPolicy": {
    "HandleSourceTableDropped": true,
    "HandleSourceTableTruncated": true,
    "HandleSourceTableAltered": true
  },
  "ErrorBehavior": {
    "DataErrorPolicy": "LOG_ERROR",
    "DataTruncationErrorPolicy": "LOG_ERROR",
    "DataErrorEscalationPolicy": "SUSPEND_TABLE",
    "DataErrorEscalationCount": 0,
    "TableErrorPolicy": "SUSPEND_TABLE",
    "TableErrorEscalationPolicy": "STOP_TASK",
    "TableErrorEscalationCount": 0,
    "RecoverableErrorCount": -1,
    "RecoverableErrorInterval": 5,
    "RecoverableErrorThrottling": true,
    "RecoverableErrorThrottlingMax": 1800,
    "ApplyErrorDeletePolicy": "IGNORE_RECORD",
    "ApplyErrorInsertPolicy": "LOG_ERROR",
    "ApplyErrorUpdatePolicy": "LOG_ERROR",
    "ApplyErrorEscalationPolicy": "LOG_ERROR",
    "ApplyErrorEscalationCount": 0,
    "FullLoadIgnoreConflicts": true
  },
  "ChangeProcessingTuning": {
    "BatchApplyPreserveTransaction": true,
    "BatchApplyTimeoutMin": 1,
    "BatchApplyTimeoutMax": 30,
    "BatchApplyMemoryLimit": 500,
    "BatchSplitSize": 0,
    "MinTransactionSize": 1000,
    "CommitTimeout": 1,
    "MemoryLimitTotal": 1024,
    "MemoryKeepTime": 60,
    "StatementCacheSize": 50
  }
}

ReplicationTaskSettingsで詳細ログ出力設定用のJSONを編集する

ReplicationTaskSettings.jsonで記録されたログ出力設定を変更してみましょう。今回は検証が目的だったので、強引に全てを変更してしまいますが、実際には用途に合わせて項目別にログ出力設定を行ってください。

$ sed -e 's/LOGGER_SEVERITY_DEFAULT/LOGGER_SEVERITY_DETAILED_DEBUG/g' ReplicationTaskSettings.json > ReplicationTaskSettings-debug.json

この設定項目については、下記に詳しく記載がありますのでご確認ください。

AWS Database Migration Service タスクのタスク設定 - AWS Database Migration Service
LOGGER_SEVERITY_ERROR — エラーメッセージがログに書き込まれます。
LOGGER_SEVERITY_WARNING — 警告とエラーメッセージがログに書き込まれます。
LOGGER_SEVERITY_INFO — 情報メッセージ、警告、エラーメッセージがログに書き込まれます。
LOGGER_SEVERITY_DEFAULT — デバッグメッセージ、情報メッセージ、警告、エラーメッセージがログに書き込まれます。
LOGGER_SEVERITY_DEBUG — デバッグメッセージ、情報メッセージ、警告、エラーメッセージがログに書き込まれます。
LOGGER_SEVERITY_DETAILED_DEBUG — すべての情報がログに書き込まれます。

詳細ログ出力が有効な新しいDMSタスクを作成する

修正済のReplicationTaskSettingｓを使って、詳細ログ出力が有効になった新しいDMSタスクを作成してみましょう。検証した環境では、file://〜の箇所に、シングルクォーテーションを付けないとエラーになったのでお気をつけください。

$ aws dms create-replication-task \
--replication-task-identifier "${DMSTASKNAME}-debug" \
--source-endpoint-arn ${SourceEndpointArn} \
--target-endpoint-arn ${TargetEndpointArn} \
--replication-instance-arn ${ReplicationInstanceArn} \
--migration-type ${MigrationType} \
--table-mappings 'file://TableMappings.json' \
--replication-task-settings 'file://ReplicationTaskSettings-debug.json'
{
"ReplicationTask": {
"SourceEndpointArn": "arn:aws:dms:us-west-2:123456789012:endpoint:K7XIXXXXXXXXXXXXXXXXXXA4DE",
"ReplicationTaskIdentifier": "dmstest-debug",
"ReplicationInstanceArn": "arn:aws:dms:us-west-2:123456789012:rep:2DKQXXXXXXXXXXXXXXXXXXRUK4",
"TableMappings": "{\n \"rules\": [\n {\n \"rule-type\": \"selection\",\n \"rule-id\": \"0\",\n \"rule-name\": \"selection rule\",\n \"rule-action\": \"include\",\n \"object-locator\": {\n \"schema-name\": \"SCOTT\",\n \"table-name\": \"%\"\n }\n },\n {\n \"rule-type\": \"transformation\",\n \"rule-id\": \"1\",\n \"rule-name\": \"RuleName 1\",\n \"rule-action\": \"convert-lowercase\",\n \"rule-target\": \"schema\",\n \"object-locator\": {\n \"schema-name\": \"%\"\n }\n },\n {\n \"rule-type\": \"transformation\",\n \"rule-id\": \"2\",\n \"rule-name\": \"RuleName 2\",\n \"rule-action\": \"convert-lowercase\",\n \"rule-target\": \"table\",\n \"object-locator\": {\n \"schema-name\": \"%\",\n \"table-name\": \"%\"\n }\n }\n ]\n}\n",
"Status": "creating",
"ReplicationTaskArn": "arn:aws:dms:us-west-2:123456789012:task:PXOLXXXXXXXXXXXXXXXXXXIOPY",
"ReplicationTaskCreationDate": 1482519174.789,
"MigrationType": "full-load",
"TargetEndpointArn": "arn:aws:dms:us-west-2:123456789012:endpoint:4VO3XXXXXXXXXXXXXXXXXXEHX4",
"ReplicationTaskSettings": "{\"TargetMetadata\":{\"TargetSchema\":\"\",\"SupportLobs\":true,\"FullLobMode\":false,\"LobChunkSize\":0,\"LimitedSizeLobMode\":true,\"LobMaxSize\":32,\"LoadMaxFileSize\":0,\"ParallelLoadThreads\":0,\"BatchApplyEnabled\":false},\"FullLoadSettings\":{\"FullLoadEnabled\":true,\"ApplyChangesEnabled\":false,\"TargetTablePrepMode\":\"DROP_AND_CREATE\",\"CreatePkAfterFullLoad\":false,\"StopTaskCachedChangesApplied\":false,\"StopTaskCachedChangesNotApplied\":false,\"ResumeEnabled\":false,\"ResumeMinTableSize\":100000,\"ResumeOnlyClusteredPKTables\":true,\"MaxFullLoadSubTasks\":8,\"TransactionConsistencyTimeout\":600,\"CommitRate\":10000},\"Logging\":{\"EnableLogging\":true,\"LogComponents\":[{\"Id\":\"SOURCE_UNLOAD\",\"Severity\":\"LOGGER_SEVERITY_DETAILED_DEBUG\"},{\"Id\":\"TARGET_LOAD\",\"Severity\":\"LOGGER_SEVERITY_DETAILED_DEBUG\"},{\"Id\":\"SOURCE_CAPTURE\",\"Severity\":\"LOGGER_SEVERITY_DETAILED_DEBUG\"},{\"Id\":\"TARGET_APPLY\",\"Severity\":\"LOGGER_SEVERITY_DETAILED_DEBUG\"},{\"Id\":\"TASK_MANAGER\",\"Severity\":\"LOGGER_SEVERITY_DETAILED_DEBUG\"}],\"CloudWatchLogGroup\":\"dms-tasks-dmsrepl\",\"CloudWatchLogStream\":\"dms-task-PXOLNIUBCR7XTGE5EDUUGJIOPY\"},\"ControlTablesSettings\":{\"historyTimeslotInMinutes\":5,\"ControlSchema\":\"\",\"HistoryTimeslotInMinutes\":5,\"HistoryTableEnabled\":false,\"SuspendedTablesTableEnabled\":false,\"StatusTableEnabled\":false},\"StreamBufferSettings\":{\"StreamBufferCount\":3,\"StreamBufferSizeInMB\":8,\"CtrlStreamBufferSizeInMB\":5},\"ChangeProcessingDdlHandlingPolicy\":{\"HandleSourceTableDropped\":true,\"HandleSourceTableTruncated\":true,\"HandleSourceTableAltered\":true},\"ErrorBehavior\":{\"DataErrorPolicy\":\"LOG_ERROR\",\"DataTruncationErrorPolicy\":\"LOG_ERROR\",\"DataErrorEscalationPolicy\":\"SUSPEND_TABLE\",\"DataErrorEscalationCount\":0,\"TableErrorPolicy\":\"SUSPEND_TABLE\",\"TableErrorEscalationPolicy\":\"STOP_TASK\",\"TableErrorEscalationCount\":0,\"RecoverableErrorCount\":-1,\"RecoverableErrorInterval\":5,\"RecoverableErrorThrottling\":true,\"RecoverableErrorThrottlingMax\":1800,\"ApplyErrorDeletePolicy\":\"IGNORE_RECORD\",\"ApplyErrorInsertPolicy\":\"LOG_ERROR\",\"ApplyErrorUpdatePolicy\":\"LOG_ERROR\",\"ApplyErrorEscalationPolicy\":\"LOG_ERROR\",\"ApplyErrorEscalationCount\":0,\"FullLoadIgnoreConflicts\":true},\"ChangeProcessingTuning\":{\"BatchApplyPreserveTransaction\":true,\"BatchApplyTimeoutMin\":1,\"BatchApplyTimeoutMax\":30,\"BatchApplyMemoryLimit\":500,\"BatchSplitSize\":0,\"MinTransactionSize\":1000,\"CommitTimeout\":1,\"MemoryLimitTotal\":1024,\"MemoryKeepTime\":60,\"StatementCacheSize\":50}}"
}
}

公式ドキュメントにも言及がありますが、1点注意事項があり、CloudWatchLogStreamの項目は、本来DMSタスク名から自動生成されるものなのですが、元の名前と同じものを静的に指定してしまっている為、AWS Management Console上では、DMSタスクのLogsタブから画面遷移ができなくなってしまうようです。仮タスクを削除した上で同じ名前のタスク名で作成すれば問題は発生しないのかもしれませんが、未検証です。

ただ、ログが取得できなくなるわけではありませんので、Cloud Watchコンソールから参照すれば特に問題はありません。

DMSタスクの詳細ログ出力を確認してみる

それでは、DMSタスクのデフォルト状態(LOGGER_SEVERITY_DEFAULT)と今回変更したLOGGER_SEVERITY_DETAILED_DEBUGのログ出力を比較してみましょう。

LOGGER_SEVERITY_DEFAULT

dms_log_default

LOGGER_SEVERITY_DETAILED_DEBUG

dms_log_debug

ぱっと見てわかるように画像で比較してみます。実際にはデバッグ設定にすると、"D:"のデバッグログが出力され、ログ量が一気に多くなったことが見て取れました。今回検証した環境はごく僅かなサンプルデータの移行で検証を行いましたが、実際にはログ量が膨大となり、思わぬ課金につながったり、逆にログ量が多すぎて必要な情報を追跡しづらくこともあり得ると思います。

下記の5種類のIDごとにそれぞれログ設定を変更できるようですので、試しながら必要に応じて組み合わせてご利用いただければと思います。